Use a tracing subscriber for LSP logging #93

DavisVaughan · 2024-12-11T19:11:28Z

Branched from #80

The LSP now activates a global tracing "subscriber" for all tracing::error!() (and friends) events. This means that we can use the free functions tracing provides to log from anywhere in the LSP (or from the parser/formatter internals) and it will get captured by this global subscriber. (Notably, I have not activated the compatibility helper for log::, and have removed that crate).

The global subscriber implements a write() method that forwards the message in a non-async way to a new logging specific thread. That logging thread can then call client.log_message().await to perform an async send of the message to the client. That's the only job of that thread.

The AuxiliaryEvent thread has gotten a bit simpler since we don't worry about logging in there now.

Checking for air.logLevel and air.dependencyLogLevels is not yet done. That is going to be 99% a frontend PR with lots of changes required in the typescript extension, and this PR felt big enough as is. So I'll wait to do that. But here is the general idea:

User sets air.logLevel to error/info/warn/debug/trace in their user level settings.json (note, ignoring workspace level)
Forward that value to the server using the initializationOptions field of type LSPAny within the InitializeParams. The client and server will need to have matching representations of what initializationOptions looks like, but I'm imagining a Settings struct where one field is logLevel.
Server gets that value in the initialize() handler and uses it to finalize the logLevel and fully set up logging

Note that this approach would work for other IDEs besides VS Code. The equivalent to the air vs code extension would just have to make sure to pass a structured initializationOptions field through to the server.

https://microsoft.github.io/language-server-protocol/specifications/lsp/3.17/specification/#initialize

This completely isolates it, and also allows us to maintain all logging related logic in `logging.rs`

Right now we don't even have the "compatibility" log layer turned on

DavisVaughan · 2024-12-11T19:14:49Z

crates/lsp/src/handlers_state.rs

+    // TODO: Get user specified log level from `params.initialization_options`
+    let log_level = None;
+
+    logging::init_logging(log_tx, log_level, params.client_info.as_ref());


Initializing logging in the initialize() handler is as early as I think we can initialize it. We are going to require information from the Client to correctly set up our logging infrastructure, so we can't do this any earlier.

DavisVaughan · 2024-12-11T19:23:01Z

crates/lsp/src/logging.rs

+    /// We use `MessageType::LOG` to prevent the middleware from adding its own
+    /// timestamp and log level labels. We add that ourselves through tracing.
+    pub(crate) async fn start(mut self) {
+        while let Some(message) = self.log_rx.recv().await {
+            self.client
+                .log_message(MessageType::LOG, message.contents)


We always forward log messages of type LOG to the middleware.

Sending LOG messages means the middleware calls the raw outputChannel.appendLine() here:
https://github.com/microsoft/vscode-languageserver-node/blob/906f5fb306e1f6059cbdcb1efd962647222b5867/client/src/common/client.ts#L1281-L1297

I prefer that over going through ERROR or WARN in the middleware, which goes through this logOutputMessage() helper:
https://github.com/microsoft/vscode-languageserver-node/blob/906f5fb306e1f6059cbdcb1efd962647222b5867/client/src/common/client.ts#L1179-L1187

That helper unconditionally prepends the log level and a timestamp to the message, but we already do this.

It will also show a notification as a toast message to the user if showNotification is true or "force", but it's always false when processing server log messages. This means that literally the only thing we would get from the middleware by sending MessageType::ERROR is for it to automatically prepend [Error - <time>] to our messages, so it seems fine to skip this.

DavisVaughan · 2024-12-11T19:25:22Z

crates/lsp/src/logging.rs

+    let writer = if client_info.is_some_and(|client_info| {
+        client_info.name.starts_with("Zed") || client_info.name.starts_with("Visual Studio Code")
+    }) {
+        BoxMakeWriter::new(LogWriterMaker::new(log_tx))
+    } else {
+        BoxMakeWriter::new(std::io::stderr)
+    };


Doing what ruff does here. It seems like VS Code and Zed handle window/logMessage well, but perhaps not every lsp client does? So they specially approve ones that handle it well and send to stderr otherwise.

DavisVaughan · 2024-12-11T19:25:46Z

crates/lsp/src/logging.rs

+        // Display local time rather than UTC
+        .with_timer(LocalTime::rfc_3339())


Nicely actually displays logs in your local time!

DavisVaughan · 2024-12-11T19:26:15Z

crates/lsp/src/logging.rs

+    if !is_test_client(client_info) {
+        tracing::subscriber::set_global_default(subscriber)
+            .expect("Should be able to set the global subscriber.");
+    }
+
+    tracing::info!("Logging initialized with level: {log_level}");
+}
+
+/// We never log during tests as tests run in parallel within a single process,
+/// but you can only have 1 global subscriber per process.
+///
+/// If you are debugging a single test, you can override this to emit messages to stderr.
+///
+/// Note that if you override this and run multiple tests in parallel, then the call
+/// to `set_global_default()` will error causing a panic.
+fn is_test_client(client_info: Option<&ClientInfo>) -> bool {
+    client_info.map_or(false, |client_info| client_info.name == "AirTestClient")
+}


Important notes here about skipping logging during tests. They are very noisy in the test output, and there are issues with running tests in parallel since the "global subscriber" is by nature a "once per process" kind of thing.

That seems strange to me. It feels like it would be better to control this with the log level. By default we don't see this output since it's captured anyway.

Tests are run in parallel that's true, but I don't think it's customary to disable logging in tests altogether? It seems like we're making it harder to debug tests here.

DavisVaughan · 2024-12-11T19:28:52Z

crates/lsp/src/logging.rs

+        // This is a potential reason to use `air_` as the crate prefix,
+        // it would make it easy to set the `tracing_level()` for only air related crates
+        let filter = if meta.target().starts_with("air") || meta.target().starts_with("lsp") {
+            self.filter.tracing_level()
+        } else {
+            tracing::Level::INFO
+        };
+
+        meta.level() <= &filter


Remember that tons of other crates use tracing::info!() and friends internally

This filter uses target, which is typically the module name, to determine the tracing level to filter with, and we never go below Info for 3rd party crates.

This is actually one reason it would be quite nice to prefix all of our crates with air_! Detection would be very simple.

I think the filter implemented in ark is more flexible? https://github.com/posit-dev/ark/blob/3b8ff6112d14f1b78640e4db55c82754c0b362bf/crates/ark/src/logger.rs#L26-L43

Is there any reason not to use this approach?

DavisVaughan · 2024-12-11T19:30:49Z

crates/lsp/src/main_loop.rs

        set.shutdown().await;
-
-        log::trace!("Main loop exited.");
    }


Remember that after the log loop is shutdown, we won't be able to see anymore messages. I've removed a few messages that would otherwise occur too soon or too late because of this to prevent confusion.

DavisVaughan · 2024-12-11T19:33:41Z

crates/lsp/src/main_loop.rs

                        LspRequest::Initialize(params) => {
-                            respond(tx, handlers_state::initialize(params, &mut self.lsp_state, &mut self.world), LspResponse::Initialize)?;
+                            // Unwrap: `Initialize` method should only be called once.
+                            let log_tx = self.log_tx.take().unwrap();
+                            respond(tx, handlers_state::initialize(params, &mut self.lsp_state, &mut self.world, log_tx), LspResponse::Initialize)?;


I quite like how lsp_server works here. Instead of Initialize being an event you handle in your main loop, it is instead handled through explicit calls to initialize_start() to receive the Initialize request, and initialize_finish() to send back an InitializeResult.

I like that because it really drives home that they are once-per-session methods, not ones that can be recalled through the main loop.

https://docs.rs/lsp-server/latest/lsp_server/struct.Connection.html#method.initialize_start

DavisVaughan · 2024-12-11T19:34:48Z

crates/lsp/src/tower_lsp.rs

-    log::trace!("Starting LSP");
-
    let (service, socket) = new_lsp();
    let server = tower_lsp::Server::new(read, write, socket);
    server.serve(service).await;
-
-    log::trace!("LSP exiting gracefully.",);


Again these messages are "too soon" or "too late" from the perspective of the log thread

Could be eprintln!() then

I feel like it would be quite odd to have two messages get sent to stderr when all other messages end up over window/logMessage. I feel like it just adds one more layer of places to look for logs. Would it be ok to try and drop these for now and see if we need them later on?

Sure that's fine with me.

DavisVaughan · 2024-12-11T19:36:10Z

crates/lsp_test/src/lsp_client.rs

+    // Regardless of how we got the params, ensure the client name is set to
+    // `AirTestClient` so we can recognize it when we set up global logging.
+    fn with_client_info(
+        mut init_params: lsp_types::InitializeParams,
+    ) -> lsp_types::InitializeParams {
+        init_params.client_info = Some(ClientInfo {
+            name: String::from("AirTestClient"),
+            version: None,
+        });
+        init_params
+    }


I like using AirTestClient as the way to determine "are we testing or not" rather than cfg(debug_assertions) because this will also "look like" testing mode in integration tests!

lionel- · 2024-12-12T15:10:09Z

crates/lsp/src/logging.rs

+    if !is_test_client(client_info) {
+        tracing::subscriber::set_global_default(subscriber)
+            .expect("Should be able to set the global subscriber.");
+    }
+
+    tracing::info!("Logging initialized with level: {log_level}");
+}
+
+/// We never log during tests as tests run in parallel within a single process,
+/// but you can only have 1 global subscriber per process.
+///
+/// If you are debugging a single test, you can override this to emit messages to stderr.
+///
+/// Note that if you override this and run multiple tests in parallel, then the call
+/// to `set_global_default()` will error causing a panic.
+fn is_test_client(client_info: Option<&ClientInfo>) -> bool {
+    client_info.map_or(false, |client_info| client_info.name == "AirTestClient")
+}


That seems strange to me. It feels like it would be better to control this with the log level. By default we don't see this output since it's captured anyway.

Tests are run in parallel that's true, but I don't think it's customary to disable logging in tests altogether? It seems like we're making it harder to debug tests here.

lionel- · 2024-12-12T15:13:25Z

crates/lsp/src/logging.rs

+        // This is a potential reason to use `air_` as the crate prefix,
+        // it would make it easy to set the `tracing_level()` for only air related crates
+        let filter = if meta.target().starts_with("air") || meta.target().starts_with("lsp") {
+            self.filter.tracing_level()
+        } else {
+            tracing::Level::INFO
+        };
+
+        meta.level() <= &filter


I think the filter implemented in ark is more flexible? https://github.com/posit-dev/ark/blob/3b8ff6112d14f1b78640e4db55c82754c0b362bf/crates/ark/src/logger.rs#L26-L43

Is there any reason not to use this approach?

crates/lsp/src/tower_lsp.rs

lionel- · 2024-12-12T15:16:17Z

crates/lsp/src/tower_lsp.rs

-    log::trace!("Starting LSP");
-
    let (service, socket) = new_lsp();
    let server = tower_lsp::Server::new(read, write, socket);
    server.serve(service).await;
-
-    log::trace!("LSP exiting gracefully.",);


Could be eprintln!() then

- `just test` is silent - `just test-verbose` is noisy and sequential - CI is noisy and sequential and `trace` level

DavisVaughan

Okay after some reworking and talking to @lionel- here is where we landed:

cargo test is silent, no logs. Aliased to just test.
cargo test -- --nocapture shows logs, but you really want to run with --test-threads 1 so the logging is scoped to the test it applies to. Use just test-verbose for this.
AIR_LOG_LEVEL=trace allows you to set the log level of air crates. air.logLevel will be the VS Code option. The option will be an enum with autocomplete.
AIR_DEPENDENCY_LOG_LEVELS=tokio=info,tower_lsp=debug allows you to set the log level of 3rd party crates. air.dependencyLogLevels will be the VS Code option. The option will be free text.
Note that by default, we do Info logs for air crates and NO logging for 3rd party crates.
CI runs with cargo test -- --nocapture --test-threads 1 and AIR_LOG_LEVEL=trace. This should make it pretty helpful if something goes wrong on CI.

DavisVaughan · 2024-12-12T21:39:07Z

crates/lsp/src/logging.rs

+//! The logging system for `air lsp`.
+//!
+//! ## Air crate logs
+//!
+//! For air crates, a single log level is supplied as one of: error, warn, info, debug,
+//! or trace, which is applied to all air crates that log.
+//!
+//! Resolution strategy:
+//!
+//! - The environment variable `AIR_LOG_LEVEL` is consulted.
+//!
+//! - The LSP `InitializeParams.initializationOptions.logLevel` option is consulted. This
+//!   can be set in VS Code / Positron using `air.logLevel`, or in Zed by supplying
+//!   `initialization_options`.
+//!
+//! - If neither are supplied, we fallback to `"info"`.
+//!
+//! ## Dependency crate logs
+//!
+//! For dependency crates, either a single log level can be supplied, or comma separated
+//! `target=level` pairs can be supplied, like `tower_lsp=debug,tokio=info`.
+//!
+//! Resolution strategy:
+//!
+//! - The environment variable `AIR_DEPENDENCY_LOG_LEVELS` is consulted.
+//!
+//! - The LSP `InitializeParams.initializationOptions.dependencyLogLevels` option is
+//!   consulted. This can be set in VS Code / Positron using `air.dependencyLogLevel`, or
+//!   in Zed by supplying `initialization_options`.
+//!
+//! - If neither are supplied, we fallback to no logging for dependency crates.


Here is the newly updated resolution strategy

crates/lsp/src/logging.rs

DavisVaughan · 2024-12-12T21:55:51Z

crates/lsp/src/tower_lsp.rs

+impl std::fmt::Display for LspNotification {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.write_str(self.into())
+    }
+}
+impl std::fmt::Display for LspRequest {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.write_str(self.into())
+    }
+}
+impl std::fmt::Display for LspResponse {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.write_str(self.into())
+    }
+}


Using strum::IntoStaticStr, we make the Display method show just the enum variant name

DavisVaughan · 2024-12-12T21:57:25Z

crates/lsp/src/tower_lsp.rs

+impl std::fmt::Debug for TraceLspNotification<'_> {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        match self.inner {
+            LspNotification::DidOpenTextDocument(params) => {
+                // Ignore the document itself in trace logs
+                f.debug_tuple(self.inner.into())
+                    .field(&params.text_document.uri)
+                    .field(&params.text_document.version)
+                    .field(&params.text_document.language_id)
+                    .finish()
+            }
+            _ => std::fmt::Debug::fmt(self.inner, f),
+        }
+    }
+}


It ended up being easier to write a wrapper type that overrides specific variants but otherwise pushes through to the "normal" derived Debug implementation. If we try and implement Debug on LspNotification directly then we lose everything it auto-derives for us, which is actually quite a lot of repetitive code.

I was thinking about this problem after our call yesterday. That's a nice solution.

DavisVaughan · 2024-12-12T22:40:14Z

crates/lsp/src/logging.rs

+// TODO:
+// - Add `air.logLevel` and `air.dependencyLogLevels` as VS Code extension options that set


I'm also considering going the rust-analyzer route of having lots of smaller namespaces for options, like in this case:

air.log.level air.log.dependencyLevels

which would come in as a LogSettings struct containing level and dependencyLevels fields.

That seems like it would be useful for grouping related options?

lionel-

Looks great!

My only comment is that I think we should unconditionally log the LSP message types at info level.

lionel- · 2024-12-13T08:10:23Z

crates/lsp/src/tower_lsp.rs

+impl std::fmt::Display for LspNotification {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.write_str(self.into())
+    }
+}
+impl std::fmt::Display for LspRequest {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.write_str(self.into())
+    }
+}
+impl std::fmt::Display for LspResponse {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.write_str(self.into())
+    }
+}


crates/lsp/src/tower_lsp.rs

lionel- · 2024-12-13T08:14:52Z

crates/lsp/src/tower_lsp.rs

+impl std::fmt::Debug for TraceLspNotification<'_> {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        match self.inner {
+            LspNotification::DidOpenTextDocument(params) => {
+                // Ignore the document itself in trace logs
+                f.debug_tuple(self.inner.into())
+                    .field(&params.text_document.uri)
+                    .field(&params.text_document.version)
+                    .field(&params.text_document.language_id)
+                    .finish()
+            }
+            _ => std::fmt::Debug::fmt(self.inner, f),
+        }
+    }
+}


I was thinking about this problem after our call yesterday. That's a nice solution.

lionel- · 2024-12-13T08:17:33Z

crates/lsp/src/tower_lsp.rs

-    log::trace!("Starting LSP");
-
    let (service, socket) = new_lsp();
    let server = tower_lsp::Server::new(read, write, socket);
    server.serve(service).await;
-
-    log::trace!("LSP exiting gracefully.",);


Sure that's fine with me.

justfile

lionel- · 2024-12-13T08:20:05Z

crates/lsp/src/tower_lsp.rs

    /// Handle to main loop. Drop it to cancel the loop, all associated tasks,
    /// and drop all owned state.
    _main_loop: tokio::task::JoinSet<()>,
 }

 impl Backend {
    async fn request(&self, request: LspRequest) -> anyhow::Result<LspResponse> {
-        self.log_info(format!("Incoming: {request:#?}"));
+        tracing::trace!("Incoming:\n{request:#?}", request = request.trace());


I think we also discussed a tracing::info() message with the message type so we can better make sense of user logs before they enable trace logging?

lionel- · 2024-12-13T08:23:04Z

crates/lsp/src/logging.rs

+    client_info.map_or(false, |client_info| client_info.name == "AirTestClient")
+}
+
+// TODO: Is there a way to generate this at compile time?


chatgpt suggests

cargo metadata --no-deps --format-version 1 | jq -r '.packages[].name'

which gives me

air air_r_formatter air_r_syntax air_formatter_test line_ending air_r_parser air_r_factory tests_macros fs lsp lsp_test biome_ungrammar xtask_codegen xtask

I guess we can add an exclude list for build-time things like biome_ungrammar. Or there's probably a way to determine dev deps from the metadata.

If you remove the jq you get a bunch of json data which is fine to ingest from Rust. This could be done in build.rs.

Of course there's a crate for this. cargo_metadata! 3f0f720

lionel- · 2024-12-13T08:41:52Z

.github/workflows/test-linux.yml

+          AIR_LOG_LEVEL: trace
+        # `--nocapture` to see our own `tracing` logs
+        # `--test-threads 1` to ensure `tracing` logs aren't interleaved
+        run: cargo test -- --nocapture --test-threads 1


Use the just alias? I don't mind either way, I guess this is more explicit.

DavisVaughan added 9 commits December 11, 2024 10:19

Teach log:: and tracing:: to send window/logMessage` messages

8cd384e

Put logging on its own thread

c4b669c

This completely isolates it, and also allows us to maintain all logging related logic in `logging.rs`

Tweak existing log usage

05a4df3

Avoid logging during tests

61881fc

Fully switch to tracing over log

59db48d

Right now we don't even have the "compatibility" log layer turned on

Send an initial log message with the level

c0755b3

Check AIR_LOG envvar on startup

f6e203e

Tweak expected option name

8d952c7

Tweak comment

e2a7858

DavisVaughan commented Dec 11, 2024

View reviewed changes

This was referenced Dec 11, 2024

Make testing more reliable and realistic #87

Closed

Remove the global AUXILIARY_EVENT_TX and use tracing #80

Merged

DavisVaughan requested a review from lionel- December 11, 2024 19:42

lionel- reviewed Dec 12, 2024

View reviewed changes

DavisVaughan added 3 commits December 12, 2024 13:08

Do log during testing, but "captured" by default

05c3dc3

- `just test` is silent - `just test-verbose` is noisy and sequential - CI is noisy and sequential and `trace` level

Add intermediate Trace* structs with custom Debug implementations

a775e77

Use Targets backed filtering

2e474a4

DavisVaughan commented Dec 12, 2024

View reviewed changes

DavisVaughan requested a review from lionel- December 12, 2024 21:58

DavisVaughan commented Dec 12, 2024

View reviewed changes

lionel- approved these changes Dec 13, 2024

View reviewed changes

DavisVaughan added 3 commits December 13, 2024 12:52

Always write the request/notify name at info!() level

6e1cdc4

Use pretty() after all because it is useful with spans

1ddd672

Write out AIR_CRATE_NAMES at build time

3f0f720

DavisVaughan merged commit a0bb387 into fix/aux-global Dec 13, 2024
4 checks passed

DavisVaughan deleted the feature/tracing-logs branch December 13, 2024 18:52

DavisVaughan mentioned this pull request Dec 13, 2024

Hook up user specified options of air.logLevel and air.dependencyLogLevels in VS Code extension #100

Open

DavisVaughan restored the feature/tracing-logs branch December 13, 2024 18:58

DavisVaughan mentioned this pull request Dec 13, 2024

Use a tracing subscriber for LSP logging #101

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Use a tracing subscriber for LSP logging #93

Use a tracing subscriber for LSP logging #93

DavisVaughan commented Dec 11, 2024 •

edited

Loading

DavisVaughan Dec 11, 2024

DavisVaughan Dec 11, 2024

DavisVaughan Dec 11, 2024

DavisVaughan Dec 11, 2024

DavisVaughan Dec 11, 2024

lionel- Dec 12, 2024

DavisVaughan Dec 11, 2024

lionel- Dec 12, 2024

DavisVaughan Dec 11, 2024

DavisVaughan Dec 11, 2024

DavisVaughan Dec 11, 2024

lionel- Dec 12, 2024

DavisVaughan Dec 12, 2024

lionel- Dec 13, 2024

DavisVaughan Dec 11, 2024

lionel- Dec 12, 2024

lionel- Dec 12, 2024

lionel- Dec 12, 2024

DavisVaughan left a comment

DavisVaughan Dec 12, 2024

DavisVaughan Dec 12, 2024

lionel- Dec 13, 2024

DavisVaughan Dec 12, 2024

lionel- Dec 13, 2024

DavisVaughan Dec 12, 2024

lionel- left a comment

lionel- Dec 13, 2024

lionel- Dec 13, 2024

lionel- Dec 13, 2024

lionel- Dec 13, 2024

lionel- Dec 13, 2024

lionel- Dec 13, 2024

DavisVaughan Dec 13, 2024

lionel- Dec 13, 2024

		// Display local time rather than UTC
		.with_timer(LocalTime::rfc_3339())

		// TODO:
		// - Add `air.logLevel` and `air.dependencyLogLevels` as VS Code extension options that set

Use a tracing subscriber for LSP logging #93

Use a tracing subscriber for LSP logging #93

Conversation

DavisVaughan commented Dec 11, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

DavisVaughan left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lionel- left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

DavisVaughan commented Dec 11, 2024 •

edited

Loading